In [1]:
from IPython.display import display, HTML
display(HTML("<style>.container {width:100% !important; }</style>"))

import glob
import pandas as pd
import numpy as np
import hvplot.pandas
import plotly.express as px
import plotly.graph_objects as go
pd.options.mode.chained_assignment = None

import datetime as dt
%autosave 30
Autosaving every 30 seconds
In [2]:
CPU_FREQ=2.60

rdtsc_df_dict = []
ttt_df_dict = []
for filename in glob.glob("exchange*.log") + glob.glob("*_1.log"):
    print('processing {}'.format(filename))
    for line in open(filename):
        tokens = line.strip().split(' ')
        if len(tokens) != 4:
            continue

        try:
            time = tokens[0]
            tag = tokens[2]
            latency = float(tokens[3])
            latency_rdtsc = latency / CPU_FREQ
            time_datetime = pd.to_datetime(time, format='%H:%M:%S.%f')
        except:
            continue

        if ' RDTSC ' in line:
            if tokens[1] != 'RDTSC':
                continue

            rdtsc_df_dict.append({'timestamp':time, 'tag':tag, 'latency':latency_rdtsc})
        elif ' TTT ' in line:
            if tokens[1] != 'TTT':
                continue

            ttt_df_dict.append({'timestamp':time, 'tag':tag, 'latency':latency})
        
rdtsc_df = pd.DataFrame.from_dict(rdtsc_df_dict)
rdtsc_df = rdtsc_df.drop_duplicates().sort_values(by='timestamp')
rdtsc_df['timestamp'] = pd.to_datetime(rdtsc_df['timestamp'], format='%H:%M:%S.%f')

ttt_df = pd.DataFrame.from_dict(ttt_df_dict)
ttt_df = ttt_df.drop_duplicates().sort_values(by='timestamp')
ttt_df['timestamp'] = pd.to_datetime(ttt_df['timestamp'], format='%H:%M:%S.%f')
processing exchange_snapshot_synthesizer.log
processing exchange_order_server.log
processing exchange_main.log
processing exchange_matching_engine.log
processing exchange_market_data_publisher.log
processing trading_main_1.log
processing trading_order_gateway_1.log
processing trading_engine_1.log
processing trading_market_data_consumer_1.log
In [3]:
for tag in rdtsc_df['tag'].unique():
    print(tag)
    
    fig = go.Figure()

    t_df = rdtsc_df[rdtsc_df['tag'] == tag].copy()
    t_df = t_df[t_df['latency'] > 0]

    q_hi = t_df['latency'].quantile(0.99)
    q_lo = t_df['latency'].quantile(0.01)
    t_df = t_df[(t_df['latency'] < q_hi) & (t_df['latency'] > q_lo)]

    mean = t_df['latency'].astype(float).mean()
    print('{} has {} observations mean {}'.format(tag, len(t_df), mean))

    rolling_window = max(1, int(len(t_df) / 100))

    use_micros = False
    if mean >= 1000:
        use_micros = True
        t_df['latency'] = t_df['latency'].astype(float) / 1000

    fig.add_trace(go.Scatter(x=t_df['timestamp'], y=t_df['latency'], name=tag))
    fig.add_trace(go.Scatter(x=t_df['timestamp'], y=t_df['latency'].rolling(rolling_window).mean(), name=tag + ' mean'))
#     fig.add_trace(go.Scatter(x=t_df['timestamp'], y=t_df['latency'].rolling(rolling_window).std(), name=tag + ' std'))

    fig.update_layout(title='performance ' + tag + ' ' + ('microseconds' if use_micros else 'nanoseconds'), height=750, width=1000, hovermode='x', legend=dict(
        yanchor="top",
        y=0.99,
        xanchor="left",
        x=0.01
    ))
    fig.show()
Exchange_FIFOSequencer_addClientRequest
Exchange_FIFOSequencer_addClientRequest has 10487 observations mean 82.03394679126538
Exchange_FIFOSequencer_sequenceAndPublish
Exchange_FIFOSequencer_sequenceAndPublish has 10374 observations mean 53909.935971585764
Exchange_MEOrderBook_checkForMatch
Exchange_MEOrderBook_checkForMatch has 5703 observations mean 163383.84224227464
Exchange_MEOrderBook_addOrder
Exchange_MEOrderBook_addOrder has 3636 observations mean 497.1089320470508
Exchange_MEOrderBook_add
Exchange_MEOrderBook_add has 5708 observations mean 337468.20750902913
Exchange_MatchingEngine_processClientRequest
Exchange_MatchingEngine_processClientRequest has 11326 observations mean 254875.95264130185
Exchange_MEOrderBook_removeOrder
Exchange_MEOrderBook_removeOrder has 2969 observations mean 1281.9594787159622
Exchange_MEOrderBook_cancel
Exchange_MEOrderBook_cancel has 5616 observations mean 56774.474989042305
Exchange_McastSocket_send
Exchange_McastSocket_send has 12158 observations mean 433.9329279866374
Exchange_TCPSocket_send
Exchange_TCPSocket_send has 18355 observations mean 185.35437839197033
Trading_MarketDataConsumer_recvCallback
Trading_MarketDataConsumer_recvCallback has 6389 observations mean 177245.91413125925
Trading_MarketOrderBook_addOrder
Trading_MarketOrderBook_addOrder has 3392 observations mean 427.95378265602324
Trading_MarketOrderBook_updateBBO
Trading_MarketOrderBook_updateBBO has 8566 observations mean 128.4547136263223
Trading_PositionKeeper_updateBBO
Trading_PositionKeeper_updateBBO has 8642 observations mean 8776.86695565485
Trading_FeatureEngine_onOrderBookUpdate
Trading_FeatureEngine_onOrderBookUpdate has 8647 observations mean 14266.052477070749
Trading_TradeEngine_algoOnOrderBookUpdate_
Trading_TradeEngine_algoOnOrderBookUpdate_ has 8647 observations mean 109645.07356931259
Trading_MarketOrderBook_removeOrder
Trading_MarketOrderBook_removeOrder has 2969 observations mean 1169.0306241417727
Exchange_MEOrderBook_match
Exchange_MEOrderBook_match has 3548 observations mean 271042.8621758737
Trading_FeatureEngine_onTradeUpdate
Trading_FeatureEngine_onTradeUpdate has 3547 observations mean 20618.933334779118
Trading_TradeEngine_algoOnTradeUpdate_
Trading_TradeEngine_algoOnTradeUpdate_ has 3548 observations mean 18355.942134246812
Trading_RiskManager_checkPreTradeRisk
Trading_RiskManager_checkPreTradeRisk has 2964 observations mean 126.83406000207619
Trading_OrderManager_newOrder
Trading_OrderManager_newOrder has 808 observations mean 89585.44411652703
Trading_OrderManager_moveOrder
Trading_OrderManager_moveOrder has 16868 observations mean 8806.37730066945
Trading_OrderManager_moveOrders
Trading_OrderManager_moveOrders has 8437 observations mean 47130.119346103704
Trading_TCPSocket_send
Trading_TCPSocket_send has 1521 observations mean 297.0525464016588
Trading_OrderGateway_recvCallback
Trading_OrderGateway_recvCallback has 2083 observations mean 86485.13072860887
Trading_OrderManager_onOrderUpdate
Trading_OrderManager_onOrderUpdate has 2361 observations mean 42613.87270713192
Trading_TradeEngine_algoOnOrderUpdate_
Trading_TradeEngine_algoOnOrderUpdate_ has 2361 observations mean 81860.59182875573
Trading_PositionKeeper_addFill
Trading_PositionKeeper_addFill has 835 observations mean 45744.09120221096
Trading_OrderManager_cancelOrder
Trading_OrderManager_cancelOrder has 716 observations mean 132393.5270734852
In [4]:
HOPS = [
    ['T1_OrderServer_TCP_read', 'T2_OrderServer_LFQueue_write'],
    ['T2_OrderServer_LFQueue_write', 'T3_MatchingEngine_LFQueue_read'],
    ['T3_MatchingEngine_LFQueue_read', 'T4_MatchingEngine_LFQueue_write'], ['T3_MatchingEngine_LFQueue_read', 'T4t_MatchingEngine_LFQueue_write'],
    ['T4_MatchingEngine_LFQueue_write', 'T5_MarketDataPublisher_LFQueue_read'], ['T4t_MatchingEngine_LFQueue_write', 'T5t_OrderServer_LFQueue_read'],
    ['T5_MarketDataPublisher_LFQueue_read', 'T6_MarketDataPublisher_UDP_write'], ['T5t_OrderServer_LFQueue_read', 'T6t_OrderServer_TCP_write'],
    ['T7_MarketDataConsumer_UDP_read', 'T8_MarketDataConsumer_LFQueue_write'], ['T7t_OrderGateway_TCP_read', 'T8t_OrderGateway_LFQueue_write'],
    ['T8_MarketDataConsumer_LFQueue_write', 'T9_TradeEngine_LFQueue_read'], ['T8t_OrderGateway_LFQueue_write', 'T9t_TradeEngine_LFQueue_read'],
    ['T9_TradeEngine_LFQueue_read', 'T10_TradeEngine_LFQueue_write'], ['T9t_TradeEngine_LFQueue_read', 'T10_TradeEngine_LFQueue_write'],
    ['T10_TradeEngine_LFQueue_write', 'T11_OrderGateway_LFQueue_read'],
    ['T11_OrderGateway_LFQueue_read', 'T12_OrderGateway_TCP_write'],
    # exchange <-> client
    ['T12_OrderGateway_TCP_write', 'T1_OrderServer_TCP_read'],
    ['T6_MarketDataPublisher_UDP_write', 'T7_MarketDataConsumer_UDP_read'], ['T6t_OrderServer_TCP_write', 'T7t_OrderGateway_TCP_read'],
]
In [ ]:
for tags in HOPS:
    tag_p, tag_n = tags
    print('{} => {}. {} => {}.'.format(tag_p, len(ttt_df[ttt_df['tag'] == tag_p]), tag_n, len(ttt_df[ttt_df['tag'] == tag_n])))

    fig = go.Figure()

    t_df = ttt_df[(ttt_df['tag'] == tag_n) | (ttt_df['tag'] == tag_p)]
    t_df['latency_diff'] = t_df['latency'].diff()
    t_df = t_df[t_df['latency_diff'] > 0]
    t_df = t_df[t_df.tag == tag_n]

    q_hi = t_df['latency_diff'].quantile(0.99)
    q_lo = t_df['latency_diff'].quantile(0.01)
    t_df = t_df[(t_df['latency_diff'] < q_hi) & (t_df['latency_diff'] > q_lo)]

    mean = t_df['latency_diff'].astype(float).mean()
    print('{} has {} observations mean {}'.format(tag_n, len(t_df), mean))

    rolling_window = max(1, int(len(t_df) / 100))

    unit = 'nanoseconds'
    if mean >= 1000000:
        unit = 'milliseconds'
        t_df['latency_diff'] = t_df['latency_diff'].astype(float) / 1000000
    elif mean >= 1000:
        unit = 'microseconds'
        t_df['latency_diff'] = t_df['latency_diff'].astype(float) / 1000

    tag_name = tag_p + ' -> ' + tag_n
    fig.add_trace(go.Scatter(x=t_df['timestamp'], y=t_df['latency_diff'], name=tag_name))
    fig.add_trace(go.Scatter(x=t_df['timestamp'], y=t_df['latency_diff'].rolling(rolling_window).mean(), name=tag_name + ' mean'))

    fig.update_layout(title='performance ' + tag_name + ' ' + unit, height=750, width=1000, hovermode='x', legend=dict(
        yanchor="top",
        y=0.99,
        xanchor="left",
        x=0.01
    ))
    fig.show()
T1_OrderServer_TCP_read => 10870. T2_OrderServer_LFQueue_write => 11558.
T2_OrderServer_LFQueue_write has 11306 observations mean 131404.89509994694
T2_OrderServer_LFQueue_write => 11558. T3_MatchingEngine_LFQueue_read => 11558.
T3_MatchingEngine_LFQueue_read has 10784 observations mean 3189226.278931751
T3_MatchingEngine_LFQueue_read => 11558. T4_MatchingEngine_LFQueue_write => 12447.
T4_MatchingEngine_LFQueue_write has 12175 observations mean 344765.1561396304
T3_MatchingEngine_LFQueue_read => 11558. T4t_MatchingEngine_LFQueue_write => 18802.
T4t_MatchingEngine_LFQueue_write has 18406 observations mean 259917.150494404
T4_MatchingEngine_LFQueue_write => 12447. T5_MarketDataPublisher_LFQueue_read => 12447.
T5_MarketDataPublisher_LFQueue_read has 12066 observations mean 1910351.753356539
T4t_MatchingEngine_LFQueue_write => 18802. T5t_OrderServer_LFQueue_read => 18802.
T5t_OrderServer_LFQueue_read has 18290 observations mean 1908845.1604155276
T5_MarketDataPublisher_LFQueue_read => 12447. T6_MarketDataPublisher_UDP_write => 12447.
T6_MarketDataPublisher_UDP_write has 12188 observations mean 317922.17394158186
T5t_OrderServer_LFQueue_read => 18802. T6t_OrderServer_TCP_write => 18802.
T6t_OrderServer_TCP_write has 18342 observations mean 273255.22625667864
In [ ]:
import session_info
session_info.show()